为什么我的接口响应时间这么长？记一次接口响应时间过长问题排查 |
您所在的位置：网站首页 › 接口异常 一般是什么原因导致的 › 为什么我的接口响应时间这么长？记一次接口响应时间过长问题排查 |
为什么我的接口响应时间这么长？记一次接口响应时间过长问题排查
|
一、情况描述
某saas应用，在请求一个接口的时候，发现响应时间非常的慢，利用前台google浏览器的F12调试，发现响应时间超过2秒 
二、问题排查
项目整体采用前后端分离，前端通过nginx实现负载转发，请求后端接口，所以首先排查是不是前台的问题，发生了某些很耗时的操作。 1. 查看nginx的响应时间
通过查看nginx的日志信息，发现nginx对接口的响应时间，差不多也在2.4秒，排除了前台的问题 因为nginx的性能非常高，所以一般情况下，从nginx到后端，不太可能会耗时这么久 2. 查看后端接口代码 @ApiOperation(value = "获取用户状态", httpMethod = "GET") @Log("获取用户状态") @GetMapping("/getUserStatus") public RetInfo getUserStatus(HttpServletRequest request) { log.info("===============获取用户状态 开始==============="); long s = System.currentTimeMillis(); RetInfo retInfo = RetInfoUtils.getRetInfoBySuccess(); Map loginMap = RequestUtils.getLoginMap(request); if(loginMap == null){ return RetInfoUtils.getRetInfoByError(CommonConstant.BUS_EXCEPTION_RESULT,"用户未登录"); } long start = System.currentTimeMillis(); Map userInfo = userInfoSrv.getUserInfo(loginMap.get("phone")); log.info("获取用户信息 耗时：" + (System.currentTimeMillis() - start)); start = System.currentTimeMillis(); if("1".equals(userInfo.get("is_enabled")) && StringUtils.isEmpty(loginMap.get("co_code"))){ //如果审核通过 刷新session HttpSession session = request.getSession(); session.setAttribute("open_session_userinfo", userInfo); session.setMaxInactiveInterval(time); } log.info("刷新session 耗时：" + (System.currentTimeMillis() - start)); retInfo.setObject(userInfo.get("is_enabled")); retInfo.setResult(userInfo.get("feed_back")); log.info("===============获取用户状态 结束============耗时： " + (System.currentTimeMillis() - s)); return retInfo; }后端代码其实也很简单，就是从session里面获取用户登录状态，通过打日志等一些方法，发现这个接口的实际执行时间，在4ms左右，完全达不到2.4s的时间，那么问题到底出在哪呢？ 3. 分析aop注解发现在接口加了一个自定义注解 @Log，这是我们自定义的注解，用于记录接口的调用日志 @Pointcut("@annotation(com.test.annotation.Log)") public void pointcut() { } @Around("pointcut()") public Object around(ProceedingJoinPoint point) { Object result = null; long beginTime = System.currentTimeMillis(); try { // 执行方法 result = point.proceed(); } catch (Throwable e) { log.error("方法执行错误::::{}", e.getMessage()); } // 执行时长(毫秒) long time = System.currentTimeMillis() - beginTime; // 保存日志 saveLog(point, time, result); return result; }这里的aop，我们使用的是同步的方法，只有在aop执行完，接口才会返回 经过日志排查，发现@Log日志入库的时间，耗时2秒多，问题出现在系统日志入库这一步，进一步排查数据库问题 4. 排查数据库问题mysql自带的库information schema中有张表processlist，可以查看所有的进程 通过查看这张表的数据，发现有一个进程一直在定时执行，经过和同事的咨询沟通，有人写了个定时任务，定时入库数据，占用了数据库资源 最后联系了负责paas资源相关的负责人，对数据库进行了相应的优化，解决了问题 |
【本文地址】